Strange log in android when using Player

[cxg1023]

My invoke flow is:
invoke with an url -> read from file -> player.set_input_size -> invoke player.push_data in 5 secs

note : i havn't called player.play yet.

Here is my code snippet:

    pub fn set_up_media(context_ver: u32) -> Result<InnerPlayer, AnyError> {
        let (sender, receiver) = ipc::channel::<PlayerEvent>().unwrap();
        let player = ServoMedia::get().unwrap().create_player(
            &ClientContextId::build(context_ver, 1),
            StreamType::Seekable,
            sender,
            None,
            None,
            Box::new(PlayerContextDummy()),
        );

        let inner_player = InnerPlayer {
            player,
            loop_: Arc::new(AtomicBool::default()),
            playback_position: Arc::new(AtomicU64::default()),
            playback_start_time: Arc::new(Mutex::new(0.)),
            playback_rate: Arc::new(Mutex::new(1.)),
            duration: Arc::new(Mutex::new(f64::INFINITY)),
            data: Arc::new(Mutex::new(vec![])),
        };
        let inner_player_clone = inner_player.clone();
        ROUTER.add_route(
            receiver.to_opaque(),
            Box::new(move |message| {
                let event = message.to().unwrap();
                inner_player_clone.handle_player_event(event);
            }),
        );

        Ok(inner_player)
    }

    pub fn handle_player_event(&self, event: PlayerEvent) {
        match event {
            PlayerEvent::EndOfStream => {
                log::debug!("player end of stream.");
                if self.looping() {
                    log::debug!("need loop from start.");
                }
            }

            PlayerEvent::Error(e) => {
                log::debug!("player error happened, {}", e);
            }
            PlayerEvent::VideoFrameUpdated => {
                log::debug!("player video frame updated.")
            }
            PlayerEvent::MetadataUpdated(ref m) => {
                log::debug!("player metadata updated: {:?}", m);
                self.playback_position.store(0, Ordering::Relaxed);

                if let Some(duration) = m.duration {
                    *self.duration.lock().unwrap() = duration.as_secs_f64();
                }

                let mut jumped = false;

                let start_position = self.playback_start_time.lock().unwrap();
                if *start_position > 0. {
                    jumped = true;
                    self.seek(*start_position);
                }
                *self.playback_start_time.lock().unwrap() = 0.;
            }
            PlayerEvent::NeedData => {
                log::debug!("player need data.")
            }
            PlayerEvent::EnoughData => {
                log::debug!("player enough data.")
            }
            PlayerEvent::PositionChanged(pos) => {
                log::debug!("player position changed: {}", pos);
                self.playback_position.store(pos, Ordering::Relaxed);
            }
            PlayerEvent::SeekData(pos, ref seek_lock) => {
                log::debug!("player seek data event with pos: {}", pos);
                seek_lock.unlock(true);

                if let Err(e) = self
                    .player
                    .lock()
                    .unwrap()
                    .push_data(self.data.lock().unwrap()[pos as usize..].to_vec())
                {
                    log::error!("push data failed: {:?}", e);
                }
                log::debug!("player seek data pushed.");
            }
            PlayerEvent::SeekDone(s) => {
                log::debug!("player seek done: {}", s);
            }
            PlayerEvent::StateChanged(ref state) => {
                log::debug!("player state changed to: {:?}, time: {:?}", state, std::time::Instant::now());
            }
        }
    }


    pub fn seek(&self, time: f64) {
        log::debug!("player seek called: {}", time);
        let time = f64::min(time, self.duration());
        let time = f64::max(time, 0.);

        let player = self.player.lock().unwrap();

        if let Err(e) = player.seek(time) {
            log::error!("player seek failed: {:?}", e);
        }
    }
`

[cxg1023]

And the log printed is:

audio_player_set_src length: 51945 time: Instant { tv_sec: 110400, tv_nsec: 341247431 }
player state changed to: Buffering, time: Instant { tv_sec: 110400, tv_nsec: 344656431 }
player need data.
push data called, data length: 51945
push data called, data pushed.
player state changed to: Paused, time: Instant { tv_sec: 110405, tv_nsec: 351023725 }
Leaving Object::GetInterface (SL_RESULT_FEATURE_UNSUPPORTED)
player seek data event with pos: 1
player seek data pushed.
player need data.

[cxg1023]

The 1st strange phenomena is: set_input_size with 51945, and then 51945 data pushed, the state changed to paused?
2nd is: Why seeked to 1 byte after data pushed?

Seems the data hasn't pushed enough?
I am not pushing data when NeedData event fired, instead in SeekData event.

[cxg1023]

I have also tried this: set_input_size -> push_data in 5s
After data pushed, metadata duration is 0ns.

`
----- set_input_size 51945 and need data event fired --------
audio_player_set_src: 51945 time: Instant { tv_sec: 115780, tv_nsec: 514727163 }
player state changed to: Buffering, time: Instant { tv_sec: 115780, tv_nsec: 516338246 }
player need data.

----- manually push_data in 5 secs ------
push data called, data pushed 51945.

------ data pushed, state changed to Paused because I havn't called player.play() yet ??? ----------
player state changed to: Paused, time: Instant { tv_sec: 115785, tv_nsec: 520992707 }
Leaving Object::GetInterface (SL_RESULT_FEATURE_UNSUPPORTED)

------ SeekData event fired with pos 1, why ??? ----------------
player seek data event with pos: 1
player seek data pushed. --------- push data from pos when SeekData fired -------------
player state changed to: Buffering, time: Instant { tv_sec: 115785, tv_nsec: 529875415 }
player state changed to: Paused, time: Instant { tv_sec: 115785, tv_nsec: 529903207 }
0xb4000071c43f5850 ../gst-libs/gst/audio/audio-resampler.c:274:convert_taps_gint16_c can't find exact taps
PlayerBase::PlayerBase()
TrackPlayerBase::TrackPlayerBase()
channel mask behavior (ignoring positional mask 0x3, using default mask 0x3 based on channel count of 2)

-------- why duration 0 ns ? --------------
player metadata updated: Metadata { duration: Some(0ns), width: 0, height: 0, format: "Ogg", is_seekable: false, video_tracks: [], audio_tracks: ["Vorbis"], is_live: false, title: Some("Horned Viper") }
`

[jdm]

Do you have runnable code that can make this straightforward to reproduce?